Do not send replay frames to spectator server if initial begin play invocation failed#37159
Conversation
…nvocation failed Until now, if the initial `BeginPlaySession()` call failed, the client would continue operating as if it didn't - it would still continue to send frames and call `EndPlaySession()` at the end of a session. Server-side, two things generally can happen after this: - The sent frames and the `EndPlaySession()` call are completely ignored as no-ops: https://github.com/ppy/osu-server-spectator/blob/7bab117e9d161455485368f63a0607a9e53f9f8a/osu.Server.Spectator/Hubs/Spectator/SpectatorHub.cs#L122-L125 https://github.com/ppy/osu-server-spectator/blob/7bab117e9d161455485368f63a0607a9e53f9f8a/osu.Server.Spectator/Hubs/Spectator/SpectatorHub.cs#L153-L157 - A hub filter (like `ClientVersionChecker`) that failed the initial `BeginPlaySession()` call continues to fail the calls to `SendFrameData()` and `EndPlaySession()`, all the while creating a storm in logs, because it needs to throw `HubException`s to communicate to users that they need to update their game, and the exceptions can't be silenced from logs because they look like every other failure. To that end, this has two goals: reduce useless network traffic, and reduce noise in spectator server logs after the client version checks were recently reactivated.
|
LGTM |
|
Tests not looking very good, checking. |
…from begin play failure
|
Above commit should do it I think, but I'll wait for CI to confirm before unblocking... As per inline comment in said commit, one way to reproduce is diff --git a/osu.Game/Online/Spectator/OnlineSpectatorClient.cs b/osu.Game/Online/Spectator/OnlineSpectatorClient.cs
index 22f8cfbf2b..a9f9de812c 100644
--- a/osu.Game/Online/Spectator/OnlineSpectatorClient.cs
+++ b/osu.Game/Online/Spectator/OnlineSpectatorClient.cs
@@ -59,10 +59,12 @@ protected override async Task<bool> BeginPlayingInternal(long? scoreToken, Spect
Debug.Assert(connection != null);
+ await Task.Delay(10000).ConfigureAwait(false);
+
try
{
await connection.InvokeAsync(nameof(ISpectatorServer.BeginPlaySession), scoreToken, state).ConfigureAwait(false);
- return true;
+ return false;
}
catch (Exception exception)
{
For reference, logging with the aforementioned commit shows the following sequence of events: |
|
CI still 4 red, but this time it looks like I just got unlucky. Rerunning to be sure. |
|
|
||
| if (!isPlaying) | ||
| { | ||
| // it is possible for this to happen if the `BeginPlayingInternal()` call takes a long time, |
There was a problem hiding this comment.
The question I pose is that what if it takes a long time but doesn't fail? We are potentially dropping frames from the start of a recorded replay... unless I'm missing something.
There was a problem hiding this comment.
I've not looked into it. If it's a real shortcoming, it's already in master.
My hope based on what I know about signalr delivery guarantees would be that signalr side invocation ordering would delay / queue the client frame sending calls until the begin play call succeeds, but I've not tested. I can try testing it tomorrow.
There was a problem hiding this comment.
The difference on master may be the clearing of frames which was added here. But yeah, let's investigate this one before pushing this out.
There was a problem hiding this comment.
I've been putting it off because I knew it was going to be annoying but I did finally test this today.
What I basically did is I took a full-stack osu + osu-server-spectator + osu-web setup and:
- added an artificial 15-second sleep in
osu-server-spectator, insideBeginPlaySession - added some logging to both sides to denote when the frames are sent (and how many times)
The good case (BeginPlaySession succeeds server-side after 15s)
The sequence of events is basically such:
- Client calls
SpectatorClient.BeginPlaying(). That method via sets and only then invokes the signalr method via in an essentially fire-and-forget fashion. There is no waiting for the operation to complete here. - Because the above invocation is fire-and-forget, despite the server still not having acknowledged the start, client is still calling
HandleFrame()/purgePendingFrames()/SendFramesInternal()/SendFrameData()(outbound to signalr). Of note, all of this is able to fire, becauseisPlayinghas been true all this time even though the server still hasn't responded to theBeginPlaySession()request - but the signalr invocations appear to all be buffered client-side, because the server isn't receiving these invocations yet, either. - Eventually
BeginPlaySession()succeeds, the client-side signalr buffer is flushed, and the server receives all of the backloggedSendFrameData()invocations and continues from there. - The end result is that the server eventually receives all of the invocations of
SendFrameData().
client-side logs
[runtime] 2026-04-08 09:19:06 [verbose]: [OnlineSpectatorClient] BeginPlayingInternal server invocation START
[runtime] 2026-04-08 09:19:07 [verbose]: GameplayClockContainer started via call to StartGameplayClock
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #1 START
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #1 END
[network] 2026-04-08 09:19:07 [verbose]: Request to https://a.ppy.sh/21 successfully completed!
[network] 2026-04-08 09:19:07 [verbose]: Request to https://a.ppy.sh/64 successfully completed!
[network] 2026-04-08 09:19:07 [verbose]: Request to https://a.ppy.sh/157 successfully completed!
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #2 START
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #2 END
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #3 START
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #3 END
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #4 START
[runtime] 2026-04-08 09:19:07 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #4 END
(...)
[runtime] 2026-04-08 09:19:21 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #73 START
[runtime] 2026-04-08 09:19:21 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #73 END
[runtime] 2026-04-08 09:19:22 [verbose]: [OnlineSpectatorClient] BeginPlayingInternal server invocation END
[runtime] 2026-04-08 09:19:22 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #74 START
[runtime] 2026-04-08 09:19:22 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #74 END
[runtime] 2026-04-08 09:19:22 [debug]: Pressed (LeftButton) handled by DrawableHitCircle+HitReceptor.
[runtime] 2026-04-08 09:19:22 [debug]: KeyDownEvent(Z, False) handled by OsuInputManager+OsuKeyBindingContainer.
[runtime] 2026-04-08 09:19:22 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #75 START
[runtime] 2026-04-08 09:19:22 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #75 END
(...)
[runtime] 2026-04-08 09:19:48 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #205 START
[runtime] 2026-04-08 09:19:48 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #205 END
[runtime] 2026-04-08 09:19:48 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #206 START
[runtime] 2026-04-08 09:19:48 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #206 END
[runtime] 2026-04-08 09:19:48 [verbose]: Beginning score submission (token:344)...
server-side logs
info: Spectator[0]
[user:157] BeginPlaySession START @ 4/8/2026 9:19:06 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] BeginPlaySession END @ 4/8/2026 9:19:22 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #1 START @ 4/8/2026 9:19:22 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #1 END @ 4/8/2026 9:19:22 AM +00:00
(...)
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #73 START @ 4/8/2026 9:19:22 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #73 END @ 4/8/2026 9:19:22 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #74 START @ 4/8/2026 9:19:22 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #74 END @ 4/8/2026 9:19:22 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #75 START @ 4/8/2026 9:19:22 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #75 END @ 4/8/2026 9:19:22 AM +00:00
(...)
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #205 START @ 4/8/2026 9:19:48 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #205 END @ 4/8/2026 9:19:48 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #206 START @ 4/8/2026 9:19:48 AM +00:00
info: Spectator[0]
[user:157] SendFrameData #206 END @ 4/8/2026 9:19:48 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "2", Target: "EndPlaySession", Arguments: [ Beatmap:843308 Mods: Ruleset:0 State:Passed ], StreamIds: [ ] }.
info: FileScoreStorage[0]
Writing replay for score 237 to 237
The bad case (BeginPlaySession() fails server-side after 15s)
- Same as the good case, the client fire-and-forgets
SpectatorClient.BeginPlaying(), setsisPlaying = true, and continues to callHandleFrame()/purgePendingFrames()/SendFramesInternal()/SendFrameData()(outbound to signalr) until the server is done. - Eventually
BeginPlaySession()fails, and the client-side signalr buffer is flushed. At this point two things happen on both ends:
a. The server receives all of the backloggedSendFrameData()invocations. BecauseBeginPlaySession()failed and the user's spectator state is basically such that they're not in a play session, all of the backlogged invocations are dropped.
b. The client receives the exception that failed the invocation ofBeginPlaySession(). In response, the user is denoted as no-longer-playing via then BecauseisPlayingis set tofalse, all incomingHandleFrame()invocations, which come directly from gameplay and are supposed to enqueue incoming frames as pending for submission later are dropped viaand all already-pending frames at this time get dropped on next requested pending frame flush viaosu/osu.Game/Online/Spectator/SpectatorClient.cs
Lines 253 to 257 in d3c820b
osu/osu.Game/Online/Spectator/SpectatorClient.cs
Lines 392 to 400 in d3c820b
client-side logs
[runtime] 2026-04-08 10:40:06 [verbose]: [OnlineSpectatorClient] BeginPlayingInternal server invocation START
[runtime] 2026-04-08 10:40:06 [verbose]: GameplayClockContainer started via call to StartGameplayClock
[runtime] 2026-04-08 10:40:06 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #1 START
[runtime] 2026-04-08 10:40:06 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #1 END
(...)
[runtime] 2026-04-08 10:40:21 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #73 START
[runtime] 2026-04-08 10:40:21 [verbose]: [OnlineSpectatorClient] SendFramesInternal server invocation #73 END
[network] 2026-04-08 10:40:21 [verbose]: OnlineSpectatorClient.BeginPlayingInternal failed: An unexpected error occurred invoking 'BeginPlaySession' on the server. HubException: Nope.
[runtime] 2026-04-08 10:40:21 [verbose]: Clearing SpectatorClient state due to failed BeginPlayingInternal call.
[runtime] 2026-04-08 10:40:21 [verbose]: Frames arrived at SpectatorClient outside of gameplay scope and will be ignored.
[runtime] 2026-04-08 10:40:21 [verbose]: SpectatorClient dropping pending frames as the user is no longer considered to be playing.
server-side logs
info: Spectator[0]
[user:157] BeginPlaySession START @ 4/8/2026 10:40:06 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
fail: Spectator[0]
[user:157] Failed to invoke hub method: BeginPlaySession(346, Beatmap:843308 Mods: Ruleset:0 State:Playing)
Microsoft.AspNetCore.SignalR.HubException: Nope.
at osu.Server.Spectator.Hubs.Spectator.SpectatorHub.BeginPlaySession(Nullable`1 scoreToken, SpectatorState state) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/Hubs/Spectator/SpectatorHub.cs:line 62
at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.ExecuteMethod(ObjectMethodExecutor methodExecutor, Hub hub, Object[] arguments)
at osu.Server.Spectator.ClientVersionChecker.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/ClientVersionChecker.cs:line 53
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at osu.Server.Spectator.ConcurrentConnectionLimiter.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/ConcurrentConnectionLimiter.cs:line 106
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at osu.Server.Spectator.LoggingHubFilter.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/LoggingHubFilter.cs:line 30
fail: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[8]
Failed to invoke hub method 'BeginPlaySession'.
Microsoft.AspNetCore.SignalR.HubException: Nope.
at osu.Server.Spectator.Hubs.Spectator.SpectatorHub.BeginPlaySession(Nullable`1 scoreToken, SpectatorState state) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/Hubs/Spectator/SpectatorHub.cs:line 62
at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.ExecuteMethod(ObjectMethodExecutor methodExecutor, Hub hub, Object[] arguments)
at osu.Server.Spectator.ClientVersionChecker.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/ClientVersionChecker.cs:line 53
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at osu.Server.Spectator.ConcurrentConnectionLimiter.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/ConcurrentConnectionLimiter.cs:line 106
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at osu.Server.Spectator.LoggingHubFilter.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next) in /Users/bdach/Documents/Work/open-source/osu-server-spectator/osu.Server.Spectator/LoggingHubFilter.cs:line 30
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.HubFilterFactory.InvokeMethodAsync(HubInvocationContext invocationContext, Func`2 next)
at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.<Invoke>g__ExecuteInvocation|18_0(DefaultHubDispatcher`1 dispatcher, ObjectMethodExecutor methodExecutor, THub hub, Object[] arguments, AsyncServiceScope scope, IHubActivator`1 hubActivator, HubConnectionContext connection, HubMethodInvocationMessage hubMethodInvocationMessage, Boolean isStreamCall)
info: Spectator[0]
[user:157] SendFrameData #1 START @ 4/8/2026 10:40:21 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
info: Spectator[0]
[user:157] SendFrameData #2 START @ 4/8/2026 10:40:21 AM +00:00
dbug: Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher[1]
Received hub invocation: InvocationMessage { InvocationId: "", Target: "SendFrameData", Arguments: [ osu.Game.Online.Spectator.FrameDataBundle ], StreamIds: [ ] }.
Hope this wall of text assuages doubts and hasn't just been a complete waste of time.
RFC
Until now, if the initial
BeginPlaySession()call failed, the client would continue operating as if it didn't - it would still continue to send frames and callEndPlaySession()at the end of a session.Server-side, two things generally can happen after this:
EndPlaySession()call are completely ignored as no-ops, orClientVersionChecker) that failed the initialBeginPlaySession()call continues to fail the calls toSendFrameData()andEndPlaySession(), all the while creating a storm in logs, because it needs to throwHubExceptions to communicate to users that they need to update their game, and the exceptions can't be silenced from logs because they look like every other failure.To that end, this has two goals: reduce useless network traffic, and reduce noise in spectator server logs after the client version checks were recently reactivated.
Probably needs tests, but unsure if everyone's going to be on board with this to begin with to be quite frank, so I'm leaving tests for when I'm told this needs tests.